fix(connection): log routine event connection loss at DEBUG - #45
Conversation
|
Codecov Report✅ All modified and coverable lines are covered by tests. 📢 Thoughts on this report? Let us know! |
fedem95
left a comment
fedem95
left a comment
There was a problem hiding this comment.
Confirmed on my physical MH201 (b13 + OWNd b8, running for 30 h): 30 event session drops, all recovered, zero "Reconnection failed" and zero availability warnings downstream. The demotion is justified.
On my hardware the reconnect occurs every ~57 min 40s.
Two suggestions for this PR:
- a flapping session is now completely silent as long as each reconnect succeeds. Until we know the per-model cadence, a burst rule would be model-agnostic: warn when drops cluster, say three within ten minutes, then at most once an hour.
asyncio.LimitOverrunErrorshares this except block. An over-long or garbage frame is not a routine session recycle; hiding it at DEBUG loses a real protocol signal. I would keep that one at WARNING.
Failure paths still log properly (Event session not connected + Reconnection failed), tests pass locally and CI is green.
`_last_drop_warning` used `0.0` as its "never warned" sentinel and was compared against `time.monotonic()`, which counts seconds since boot. So `now - 0.0 >= 3600` really meant "has this host been up for an hour": on a freshly booted machine (every CI runner, and a Home Assistant box right after a reboot) the "dropped N times in 10 minutes" warning was silently suppressed. This is why test_event_connection_drops_clustering passed locally but failed on all four CI matrix entries. - Use `None` as the sentinel. - Lift 3 / 600 / 3600 into DROP_BURST_COUNT, DROP_BURST_WINDOW and DROP_WARNING_INTERVAL next to the other reconnect constants, and format the window into the log message instead of hard-coding it. - Move the "covers EOF, RST, ..." comment back to the except clause it describes. - Replace the wall-clock-dependent burst test with clock-patched tests covering: burst on a fresh host, drops spread over > 10 min staying at DEBUG, a second warning after DROP_WARNING_INTERVAL, and the tracker surviving a real `_reconnect()` (which goes through `connect()`). The clock patch replaces only `OWNd.connection.time`, so asyncio's own loop clock is untouched. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
|
@fedem95 thanks for the review and the 30 h MH201 run — both suggestions are in, and Why CI failed but local runs passed. The first burst implementation used Burst rule (your first point):
Tests are now clock-patched via a All 8 checks green; |
fedem95
left a comment
fedem95
left a comment
There was a problem hiding this comment.
test_event_connection_drop_tracker_survives_reconnect is a nice addition, mocking _reconnect in the other tests would have hidden a reset inside connect().
One tiny thing, non-blocking: the warning always reads "dropped 3 times in 600s" even when the three drops happened five seconds apart, which reads as ten minutes of trouble. Passing the actual span (now - self._recent_drops[0]) would be more informative.
Approving
Per review: the warning always read "dropped 3 times in 600s" because it formatted the measurement window rather than the observed span, so three drops five seconds apart looked like ten minutes of trouble. Log `now - self._recent_drops[0]` instead, which is the span the drops in the current window actually covered. Adds test_event_connection_drop_burst_reports_real_span (a burst spread over 400s reports 400s), and the two existing burst assertions now pin the real 1.0s span instead of the window constant. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
fedem95
left a comment
fedem95
left a comment
There was a problem hiding this comment.
Span fix is in and it reads correctly now — I ran it: three drops five seconds apart log "dropped 3 times in 5s", three spread over 400 s log "in 400s". The dedicated test for the slow burst is a good addition.
Is ok for me
3 participants
Summary
Follows up on real-world testing feedback from @marcob79 in OpenWebNet-HA/MyHOME#304 and the review by @fedem95 below.
Gateways such as the MH200/MH201 enforce a hard ~1-hour session lifetime on the event connection. Every hour the gateway cleanly closes the socket;
OWNEventSession.get_next()catches the resultingIncompleteReadError/ConnectionResetErrorand reconnects within milliseconds with zero frame loss. Because that path logged atWARNING, Home Assistant surfaced an alarming banner in Settings → System → Logs once an hour for a connection that was perfectly healthy.Behaviour after this PR
DEBUG— "Event connection lost, reconnecting..."DROP_BURST_COUNT(3) drops withinDROP_BURST_WINDOW(10 min)WARNING— "Event connection dropped N times in 600s; network may be unstable.", repeated at most once perDROP_WARNING_INTERVAL(1 h)asyncio.LimitOverrunError(over-long / garbage frame)WARNING— kept separate from the routine-drop path, as it is a protocol signal, not a session recycle_reconnect()fails (Event session not connected/Reconnection failed; next attempt in …)WARNING— unchangedDownstream integrations (MyHOME) keep their own 60 s availability grace period and still warn if an outage actually persists.
Changes
OWNd/connection.pyDEBUG.WARNING, rate-limited to once per hour. Thresholds are the new module constantsDROP_BURST_COUNT,DROP_BURST_WINDOW,DROP_WARNING_INTERVALnext toRECONNECT_PAUSE*.asyncio.LimitOverrunErrorsplit into its ownexceptatWARNING.tests/test_connection.py— clock-patched, deterministic tests for: routine drop at DEBUG, oversized frame at WARNING, burst on a freshly booted host, drops > 10 min apart staying at DEBUG, second warning after the hourly interval, and the tracker surviving a real_reconnect().Fix for the CI failure on the previous push
The first burst implementation used
0.0as the "never warned" sentinel and compared it againsttime.monotonic(), which is seconds since boot.now - 0.0 >= 3600therefore meant "has this host been up for an hour" — true on a developer laptop and on @fedem95's 30 h MH201 test box, false on every fresh CI VM and on a Home Assistant host right after a reboot. The sentinel is nowNone, andtest_event_connection_drop_burst_is_warning_on_fresh_hostpins the clock atmonotonic() = 100.0so the regression cannot come back.